Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Issue: Message: System.TimeoutException : ReceiveAsync timed out #130

Open
jarzab3 opened this issue Jan 15, 2019 · 1 comment
Open

Issue: Message: System.TimeoutException : ReceiveAsync timed out #130

jarzab3 opened this issue Jan 15, 2019 · 1 comment

Comments

@jarzab3
Copy link

jarzab3 commented Jan 15, 2019

Hi All,

I have an issue when trying to run a EndToEndTests.

Visual Studio Logs:

Test Name:	Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.BasicFunctionalityTest
Test FullName:	Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.BasicFunctionalityTest
Test Source:	C:\Users\Adam\projects\15_01_azure-iot-protocol-gateway\test\ProtocolGateway.Tests\EndToEndTests.cs : line 181
Test Outcome:	Failed
Test Duration:	0:00:28.32

Result StackTrace:	
at Microsoft.Azure.Devices.ProtocolGateway.Tests.ReadListeningHandler.<ReceiveAsync>d__10.MoveNext() in C:\Users\Adam\projects\15_01_azure-iot-protocol-gateway\test\ProtocolGateway.Tests\ReadListeningHandler.cs:line 82
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.ClientScenarios.<GetPart1SpecificSteps>d__5.MoveNext() in C:\Users\Adam\projects\15_01_azure-iot-protocol-gateway\test\ProtocolGateway.Tests\EndToEndTests.cs:line 448
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.ClientScenarios.<RunPart1StepsAsync>d__4.MoveNext() in C:\Users\Adam\projects\15_01_azure-iot-protocol-gateway\test\ProtocolGateway.Tests\EndToEndTests.cs:line 428
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.Devices.ProtocolGateway.Tests.Extensions.TaskExtensions.<WithTimeoutInternal>d__1.MoveNext() in C:\Users\Adam\projects\15_01_azure-iot-protocol-gateway\test\ProtocolGateway.Tests\Extensions\TaskExtensions.cs:line 29
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.<BasicFunctionalityTest>d__26.MoveNext() in C:\Users\Adam\projects\15_01_azure-iot-protocol-gateway\test\ProtocolGateway.Tests\EndToEndTests.cs:line 276
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
Result Message:	System.TimeoutException : ReceiveAsync timed out
Result StandardOutput:	
EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.Internal.Logging.InternalLoggerFactory] [message : Using EventSource as the default logging framework] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:56.9347644Z, ProcessId : 5624, ThreadId : 3580


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.Internal.Logging.InternalLoggerFactory] [message : Using EventSource as the default logging framework] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:56.9447382Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Transport.Channels.DefaultChannelId] [message : -Dio.netty.processId: 2063211 (auto-detected)] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0599470Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Transport.Channels.DefaultChannelId] [message : -Dio.netty.machineId: 4C:CC:6A:FF:FE:F4:1C:40 (auto-detected)] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0808839Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.Internal.PlatformDependent] [message : -Dio.netty.noPreferDirect: True] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0828785Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.numHeapArenas: 8] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0908586Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.numDirectArenas: 8] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0908586Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.pageSize: 8192] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.maxOrder: 11] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.chunkSize: 16777216] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.tinyCacheSize: 512] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.smallCacheSize: 256] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.normalCacheSize: 64] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.maxCachedBufferCapacity: 32768] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.PooledByteBufferAllocator] [message : -Dio.netty.allocator.cacheTrimInterval: 8192] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0918547Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.ByteBufferUtil] [message : -Dio.netty.allocator.type: pooled] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.0993439Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.ResourceLeakDetector] [message : -Dio.netty.leakDetection.level: simple] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.1103134Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.ResourceLeakDetector] [message : -Dio.netty.leakDetection.targetRecords: 4] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.1103134Z, ProcessId : 5624, ThreadId : 10512


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963] HANDLER_ADDED] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.2489840Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963] REGISTERED] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.2499804Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963] CONNECT: 127.0.0.1:8883] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.2529733Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] ACTIVE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.2599538Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.AbstractByteBuffer] [message : -Dio.netty.buffer.bytebuf.checkAccessible: True] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.2659386Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.2789077Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] WRITE: ConnectPacket[Type=CONNECT, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.3782205Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] FLUSH] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.4625153Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.4756599Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.4756599Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.4846361Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.4856342Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] USER_EVENT: TlsHandshakeCompletionEvent(SUCCESS)] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.5105789Z, ProcessId : 5624, ThreadId : 4876


User Event: TlsHandshakeCompletionEvent(SUCCESS)
EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.5125611Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:57.5125611Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED: ConnAckPacket[Type=CONNACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.1163507Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.1173320Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.1173320Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] WRITE: SubscribePacket[Type=SUBSCRIBE, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.1278115Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] WRITE: SubscribePacket[Type=SUBSCRIBE, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.1288090Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] FLUSH] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.1288090Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED: SubAckPacket[Type=SUBACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.4608612Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.4608612Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.4608612Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED: SubAckPacket[Type=SUBACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.5935053Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.5935053Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.5935053Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] WRITE: PublishPacket[Type=PUBLISH, QualityOfService=AtMostOnce, Duplicate=False, Retain=False], 26B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|100000000| 7B 22 74 65 73 74 22 3A 20 22 74 65 6C 65 6D 65 |{"test": "teleme|
|100000010| 74 72 79 2D 51 6F 53 30 22 7D                   |try-QoS0"}      |
+--------+-------------------------------------------------+----------------+] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.5984916Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] WRITE: PublishPacket[Type=PUBLISH, QualityOfService=AtLeastOnce, Duplicate=False, Retain=False], 21B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|100000000| 7B 22 74 65 73 74 22 3A 20 22 74 65 6C 65 6D 65 |{"test": "teleme|
|100000010| 74 72 79 22 7D                                  |try"}           |
+--------+-------------------------------------------------+----------------+] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.5994897Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] FLUSH] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.5994897Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED: PubAckPacket[Type=PUBACK, QualityOfService=AtMostOnce, Duplicate=False, Retain=False]] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.7670411Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] RECEIVED_COMPLETE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.7670411Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] READ] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:55:58.7670411Z, ProcessId : 5624, ThreadId : 4876


EventId : 2, Level : Verbose, Message : , Payload : [source : CLIENT] [message : [id: 0x576af963, [::ffff:127.0.0.1]:57507 => [::ffff:127.0.0.1]:8883] CLOSE] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T16:56:18.6453437Z, ProcessId : 5624, ThreadId : 4876

Server Logs:

EventId : 2, Level : Informational, Message : , Payload : [message : Initializing TLS endpoint on port 8883 with certificate 505B7CACFF3B259161C1CF3EC5622843EFFD135F.] [info : ] , EventName : InfoInfo, Timestamp : 2019-01-15T15:11:07.2437393Z, ProcessId : 14996, ThreadId : 2360

EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Transport.Channels.DefaultChannelId] [message : -Dio.netty.processId: 286990 (auto-detected)] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T15:11:07.2507297Z, ProcessId : 14996, ThreadId : 2360

EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Transport.Channels.DefaultChannelId] [message : -Dio.netty.machineId: 4C:CC:6A:FF:FE:F4:1C:40 (auto-detected)] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T15:11:07.2706682Z, ProcessId : 14996, ThreadId : 2360

EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Buffers.ByteBufferUtil] [message : -Dio.netty.allocator.type: pooled] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T15:11:07.2744388Z, ProcessId : 14996, ThreadId : 2360

EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.ResourceLeakDetector] [message : -Dio.netty.leakDetection.level: simple] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T15:11:07.2794029Z, ProcessId : 14996, ThreadId : 2360

EventId : 2, Level : Verbose, Message : , Payload : [source : DotNetty.Common.ResourceLeakDetector] [message : -Dio.netty.leakDetection.targetRecords: 4] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T15:11:07.2804001Z, ProcessId : 14996, ThreadId : 2360

EventId : 2, Level : Informational, Message : , Payload : [message : Started] [info : ] , EventName : InfoInfo, Timestamp : 2019-01-15T15:11:07.3023512Z, ProcessId : 14996, ThreadId : 15640

EventId : 2, Level : Verbose, Message : , Payload : [s ource : DotNetty.Buffers.AbstractByteBuffer] [message : -Dio.netty.buffer.bytebuf.checkAccessible: True] [info : ] , EventName : DebugInfo, Timestamp : 2019-01-15T15:11:18.3878514Z, ProcessId : 14996, ThreadId : 13084

EventId : 2, Level : Informational, Message : , Payload : [message : ClientAuthenticated] [info : d42e668fe8684b85bfd99fe0513f45e6 [IotHubHostName: cq-iot-hub-1.azure-devices.net; PolicyName: <none>; Scope: SasToken]] [scope : 0330c9b6] , EventName : InfoInfo, Timestamp : 2019-01-15T15:11:43.0898430Z, ProcessId : 14996, ThreadId : 13084

EventId : 1, Level : Verbose, Message : , Payload : [message : Connection established.] [info : d42e668fe8684b85bfd99fe0513f45e6 [IotHubHostName: cq-iot-hub-1.azure-devices.net; PolicyName: <none>; Scope: SasToken]] [scope : 0330c9b6] , EventName : VerboseInfo, Timestamp : 2019-01-15T15:11:43.5580494Z, ProcessId : 14996, ThreadId : 13084

EventId : 4, Level : Warning, Message : , Payload : [source : DotNetty.Common.Utilities.ReferenceCountUtil] [message : Failed to release a message: PooledHeapByteBuffer(freed)] [exception : DotNetty.Common.Utilities.IllegalReferenceCountException: refCnt: 0, decrement: 1
   at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release0(Int32 decrement)
   at DotNetty.Buffers.AbstractReferenceCountedByteBuffer.Release()
   at DotNetty.Common.Utilities.ReferenceCountUtil.SafeRelease(IReferenceCounted msg)] , EventName : WarningInfo, Timestamp : 2019-01-15T15:12:03.8246020Z, ProcessId : 14996, ThreadId : 13084

EventId : 3, Level : Warning, Message : , Payload : [message : Failed sending Will Message.] [exception : System.InvalidOperationException: Topic name `last/word` could not be matched against any of the configured routes.
   at Microsoft.Azure.Devices.ProtocolGateway.IotHubClient.IotHubClient.<SendAsync>d__13.MoveNext() in C:\Users\Adam\projects\azure-iot-protocol-gateway\src\ProtocolGateway.IotHubClient\IotHubClient.cs:line 132
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.Devices.ProtocolGateway.Mqtt.MqttAdapter.<PublishToServerAsync>d__55.MoveNext() in C:\Users\Adam\projects\azure-iot-protocol-gateway\src\ProtocolGateway.Core\Mqtt\MqttAdapter.cs:line 388
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.GetResult()
   at Microsoft.Azure.Devices.ProtocolGateway.Mqtt.MqttAdapter.<CompletePublishAsync>d__85.MoveNext() in C:\Users\Adam\projects\azure-iot-protocol-gateway\src\ProtocolGateway.Core\Mqtt\MqttAdapter.cs:line 1112] [scope : 0330c9b6] , EventName : WarningInfo, Timestamp : 2019-01-15T15:12:30.6207798Z, ProcessId : 14996, ThreadId : 13084

EventId : 3, Level : Warning, Message : , Payload : [message : Closing connection for device: d42e668fe8684b85bfd99fe0513f45e6 [IotHubHostName: cq-iot-hub-1.azure-devices.net; PolicyName: <none>; Scope: SasToken]] [exception : Microsoft.Azure.Devices.ProtocolGateway.ProtocolGatewayException: Channel closed.] [scope : ] , EventName : WarningInfo, Timestamp : 2019-01-15T15:12:30.6217836Z, ProcessId : 14996, ThreadId : 13084
@anhashia
Copy link

@jarzab3
It seems to be passing with latest master of the protocol gateway that uses IoT C# device SDK version 1.20.0

Protocol gateway was recently updated to use newly released IoT device SDK version 1.20.0

Below is the output

Test Name:	Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.BasicFunctionalityTest
Test FullName:	Microsoft.Azure.Devices.ProtocolGateway.Tests.EndToEndTests.BasicFunctionalityTest
Test Source:	C:\works\azure-iot-protocol-gateway-master\test\ProtocolGateway.Tests\EndToEndTests.cs : line 182
Test Outcome:	Passed
Test Duration:	0:03:19.725

Please retest with latest master and see how it goes.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@jarzab3 @anhashia