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.

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

R2dbcEntityTemplate.insert(…) doesn't propagate error signals after data signal #552

Closed
niciosity opened this issue Mar 9, 2021 · 8 comments
Assignees
Labels
type: bug A general bug

Comments

@niciosity
Copy link

niciosity commented Mar 9, 2021

  • Driver: r2dbc-mssql 0.8.5.RELEASE, r2dbc-pool 0.8.5.RELEASE, r2dbc-spi 0.8.3.RELEASE, spring-data-r2dbc 1.2.5, 1.3.0.-M4
  • Database: MS SQL Server 2017
  • Java: Java 11.0.8, 15.0.1
  • OS: Windows 10, macOS

Database table schema.

CREATE TABLE [dbo].[customer](
	[customer_id] [char](36) NOT NULL,
	[name] [varchar](10) NOT NULL
) ON [PRIMARY]

Exception is not thrown when do SQL insert/update using ReactiveCrudRepository's save method on Microsoft SQL Server. Tested using spring-data-r2dbc latest released (1.2.5) and also the snapshot (1.3.0-M4), both shown the same result. No error, no record inserted.

Tried testing on MySQL using same code, it working the exception is thrown as expected.

:: Debug Log ::

2021-03-09 10:38:30,515 [main] INFO  DemoApplicationKt - Started DemoApplicationKt in 1.609 seconds (JVM running for 2.425)
2021-03-09 10:38:30,518 [main] INFO  DemoApplication - START THE TESTING >>
2021-03-09 10:38:30,606 [main] DEBUG ReactorNettyClient - [cid: 0x1] connect()
2021-03-09 10:38:30,647 [main] DEBUG TcpResources - [tcp] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-tcp, daemon=true, selectCount=8, workerCount=8}
2021-03-09 10:38:30,647 [main] DEBUG TcpResources - [tcp] resources will use the default ConnectionProvider: reactor.netty.resources.DefaultPooledConnectionProvider@234cd86c
2021-03-09 10:38:30,649 [main] DEBUG DefaultLoopIOUring - Default io_uring support : false
2021-03-09 10:38:30,658 [main] DEBUG DefaultLoopEpoll - Default Epoll support : false
2021-03-09 10:38:30,659 [main] DEBUG DefaultLoopKQueue - Default KQueue support : false
2021-03-09 10:38:30,663 [main] DEBUG MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
2021-03-09 10:38:30,678 [main] DEBUG NioEventLoop - -Dio.netty.noKeySetOptimization: false
2021-03-09 10:38:30,678 [main] DEBUG NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
2021-03-09 10:38:30,679 [main] DEBUG PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
2021-03-09 10:38:30,708 [main] DEBUG NetUtil - -Djava.net.preferIPv4Stack: false
2021-03-09 10:38:30,708 [main] DEBUG NetUtil - -Djava.net.preferIPv6Addresses: false
2021-03-09 10:38:30,719 [main] DEBUG NetUtilInitializations - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
2021-03-09 10:38:30,719 [main] DEBUG NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
2021-03-09 10:38:30,745 [main] DEBUG NativeLibraryLoader - -Dio.netty.native.workdir: /var/folders/45/ksbnwb2n6070054nw4y3_sfm0000gp/T (io.netty.tmpdir)
2021-03-09 10:38:30,745 [main] DEBUG NativeLibraryLoader - -Dio.netty.native.deleteLibAfterLoading: true
2021-03-09 10:38:30,745 [main] DEBUG NativeLibraryLoader - -Dio.netty.native.tryPatchShadedId: true
2021-03-09 10:38:30,826 [main] DEBUG NativeLibraryLoader - Successfully loaded the library /var/folders/45/ksbnwb2n6070054nw4y3_sfm0000gp/T/libnetty_resolver_dns_native_macos_x86_6414940256782516219731.dylib
2021-03-09 10:38:30,832 [main] DEBUG DnsServerAddressStreamProviders - io.netty.resolver.dns.macos.MacOSDnsServerAddressStreamProvider: available
2021-03-09 10:38:30,855 [main] DEBUG DefaultChannelId - -Dio.netty.processId: 21165 (auto-detected)
2021-03-09 10:38:30,859 [main] DEBUG DefaultChannelId - -Dio.netty.machineId: ac:de:48:ff:fe:00:11:22 (auto-detected)
2021-03-09 10:38:30,889 [reactor-tcp-nio-2] DEBUG TransportConfig - [id: 0x4d87a452] Initialized pipeline DefaultChannelPipeline{(reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-03-09 10:38:30,927 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433] Connected new channel
2021-03-09 10:38:30,928 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433] onStateChange([connected], SimpleConnection{channel=[id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433]})
2021-03-09 10:38:30,932 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433]}})
2021-03-09 10:38:30,964 [reactor-tcp-nio-2] DEBUG FluxReceive - [id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2021-03-09 10:38:30,981 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] exchange()
2021-03-09 10:38:30,987 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] exchange(subscribed)
2021-03-09 10:38:30,987 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Initiating exchange
2021-03-09 10:38:30,989 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Request: PRELOGIN [tokens=[Version [version=0, subbuild=0], Encryption [encryption=0], InstanceValidation [instanceName=MSSQLServer�], TraceId [connectionId=a44560aa-46af-4b78-9960-ddb5b4dacc70, activityId=null, activitySequence=0], Terminator []]]
2021-03-09 10:38:31,005 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: PRELOGIN [tokens=[Version [version=14, subbuild=3356], Encryption [encryption=0], InstanceValidation [instanceName=�], UnknownToken, Terminator []]]
2021-03-09 10:38:31,069 [reactor-tcp-nio-2] DEBUG OpenSsl - netty-tcnative not in the classpath; OpenSslEngine will be unavailable.
2021-03-09 10:38:31,147 [reactor-tcp-nio-2] DEBUG JdkSslContext - Default protocols (JDK): [TLSv1.3, TLSv1.2, TLSv1.1, TLSv1] 
2021-03-09 10:38:31,147 [reactor-tcp-nio-2] DEBUG JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384]
2021-03-09 10:38:31,159 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Registering Context Proxy and SSL Event Handlers to propagate SSL events to channelRead()
2021-03-09 10:38:31,192 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 10:38:31,193 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Flushing output buffer and enable auto-read
2021-03-09 10:38:31,226 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 10:38:31,227 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 10:38:31,227 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 10:38:31,227 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Flushing output buffer and enable auto-read
2021-03-09 10:38:31,233 [reactor-tcp-nio-2] DEBUG SslHandler - [id: 0x4d87a452, L:/127.0.0.1:63407 - R:localhost/127.0.0.1:1433] HANDSHAKEN: protocol:TLSv1.2 cipher suite:TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2021-03-09 10:38:31,233 [reactor-tcp-nio-2] DEBUG TdsSslHandler - [cid: 0x1] SSL Handshake done
2021-03-09 10:38:31,233 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: NEGOTIATED
2021-03-09 10:38:31,238 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Request: Login7 [header=DefaultHeaderOptions [type=TDS7_LOGIN, status=0], tdsVersion=VER_DENALI, packetSize=8000, clientPid=0, connectionId=0, tokens=[LoginRequestToken [tokenType=Hostname], LoginRequestToken [tokenType=Username], LoginRequestToken [tokenType=Password], LoginRequestToken [tokenType=AppName], LoginRequestToken [tokenType=Servername], LoginRequestToken [tokenType=IntName], LoginRequestToken [tokenType=Database]]]
2021-03-09 10:38:31,252 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=37, changeType=Database, newValue=selfinquiry]
2021-03-09 10:38:31,252 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: InfoToken [number=5701, state=2, infoClass=0, message='Changed database context to 'selfinquiry'.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 10:38:31,252 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Info: Code [5701] Severity [INFORMATIONAL]: Changed database context to 'selfinquiry'.
2021-03-09 10:38:31,252 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=8, changeType=SQLCollation, newValue=ОÐ�]
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=23, changeType=Language, newValue=us_english]
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: InfoToken [number=5703, state=1, infoClass=0, message='Changed language setting to us_english.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Info: Code [5703] Severity [INFORMATIONAL]: Changed language setting to us_english.
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: LoginAckToken [clientInterface=1, tdsVersion=1946157060, progrName='Microsoft SQL Server��", version=14.00.3356]
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=19, changeType=Packetsize, newValue=8000]
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: FeatureExtAckToken [featureTokens=[ColumnEncryption [tceVersion=1]]]
2021-03-09 10:38:31,261 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneToken [done=true, hasCount=false, rowCount=0, hasMore=false, currentCommand=0]
2021-03-09 10:38:31,267 [reactor-tcp-nio-2] DEBUG SimpleMssqlStatement - [cid: 0x1] Start direct exchange for  SELECT CAST(SERVERPROPERTY('Edition') AS VARCHAR(255)) AS Edition, CAST(@@VERSION AS VARCHAR(255)) as VersionString
2021-03-09 10:38:31,268 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] exchange()
2021-03-09 10:38:31,274 [reactor-tcp-nio-2] DEBUG QUERY - [cid: 0x1] Executing query:  SELECT CAST(SERVERPROPERTY('Edition') AS VARCHAR(255)) AS Edition, CAST(@@VERSION AS VARCHAR(255)) as VersionString
2021-03-09 10:38:31,274 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] exchange(subscribed)
2021-03-09 10:38:31,274 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Queueing exchange
2021-03-09 10:38:31,274 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Initiating queued exchange
2021-03-09 10:38:31,275 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Request: SQLBatch [sql=" SELECT CAST(SERVERPROPERTY('Edition') AS VARCHAR(255)) AS Edition, CAST(@@VERSION AS VARCHAR(255)) as VersionString"]
2021-03-09 10:38:31,284 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ColumnMetadataToken [columns=[Column [name='Edition", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null], Column [name='VersionString", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null]]]
2021-03-09 10:38:31,285 [reactor-tcp-nio-2] DEBUG MssqlResult - [cid: 0x1] Creating new result
2021-03-09 10:38:31,287 [reactor-tcp-nio-2] DEBUG MssqlResult - [cid: 0x1] Result column definition: ColumnMetadataToken [columns=[Column [name='Edition", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null], Column [name='VersionString", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null]]]
2021-03-09 10:38:31,290 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: io.r2dbc.mssql.message.token.RowToken@7852b6f3
2021-03-09 10:38:31,291 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneToken [done=true, hasCount=true, rowCount=1, hasMore=false, currentCommand=0]
2021-03-09 10:38:31,293 [reactor-tcp-nio-2] DEBUG DefaultDatabaseClient - Executing SQL statement [INSERT INTO customer (customer_id, name) VALUES (@P0_customerid, @P1_name)]
2021-03-09 10:38:31,293 [reactor-tcp-nio-2] DEBUG MssqlConnection - [cid: 0x1] Creating statement for SQL: [INSERT INTO customer (customer_id, name) VALUES (@P0_customerid, @P1_name)]
2021-03-09 10:38:31,299 [reactor-tcp-nio-2] DEBUG ParametrizedMssqlStatement - [cid: 0x1] Start direct exchange for INSERT INTO customer (customer_id, name) VALUES (@P0_customerid, @P1_name) SELECT SCOPE_IDENTITY() AS GENERATED_KEYS
2021-03-09 10:38:31,303 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] exchange()
2021-03-09 10:38:31,304 [reactor-tcp-nio-2] DEBUG MssqlResult - [cid: 0x1] Creating new result
2021-03-09 10:38:31,305 [reactor-tcp-nio-2] DEBUG QUERY - [cid: 0x1] Executing query: INSERT INTO customer (customer_id, name) VALUES (@P0_customerid, @P1_name) SELECT SCOPE_IDENTITY() AS GENERATED_KEYS
2021-03-09 10:38:31,305 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] exchange(subscribed)
2021-03-09 10:38:31,305 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Queueing exchange
2021-03-09 10:38:31,305 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Initiating queued exchange
2021-03-09 10:38:31,306 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Request: RPCRequest [procName='null', procId=10, optionFlags=io.r2dbc.mssql.message.token.RpcRequest$OptionFlags@2ff9b8de, statusFlags=0, parameterDescriptors=[RpcString [name='null', value=INSERT INTO customer (customer_id, name) VALUES (@P0_customerid, @P1_name) SELECT SCOPE_IDENTITY() AS GENERATED_KEYS], RpcString [name='null', value=@P0_customerid nvarchar(4000),@P1_name nvarchar(4000)], EncodedRpcParameter [name='P0_customerid', value=io.r2dbc.mssql.codec.CharacterEncoder$NvarcharEncoded@5d803da9], EncodedRpcParameter [name='P1_name', value=io.r2dbc.mssql.codec.CharacterEncoder$NvarcharEncoded@5b15d969]]]
2021-03-09 10:38:31,316 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ErrorToken [number=8152, state=30, infoClass=16, message='String or binary data would be truncated.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 10:38:31,316 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Warning: Code [8152] Severity [GENERAL_ERROR]: String or binary data would be truncated.
2021-03-09 10:38:31,317 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: InfoToken [number=3621, state=0, infoClass=0, message='The statement has been terminated.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 10:38:31,317 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Info: Code [3621] Severity [INFORMATIONAL]: The statement has been terminated.
2021-03-09 10:38:31,317 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneInProcToken [done=false, hasCount=false, rowCount=0, hasMore=true, currentCommand=195]
2021-03-09 10:38:31,318 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ColumnMetadataToken [columns=[Column [name='GENERATED_KEYS", type=MutableTypeInformation [maxLength=17, lengthStrategy=BYTELENTYPE, precision=38, displaySize=40, scale=0, flags=33, serverType=numeric, userType=0, udtTypeName="null", collation=null, charset=null], table=null]]]
2021-03-09 10:38:31,318 [reactor-tcp-nio-2] DEBUG MssqlResult - [cid: 0x1] Result column definition: ColumnMetadataToken [columns=[Column [name='GENERATED_KEYS", type=MutableTypeInformation [maxLength=17, lengthStrategy=BYTELENTYPE, precision=38, displaySize=40, scale=0, flags=33, serverType=numeric, userType=0, udtTypeName="null", collation=null, charset=null], table=null]]]
2021-03-09 10:38:31,318 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: io.r2dbc.mssql.message.token.RowToken@14394505
2021-03-09 10:38:31,321 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] close()
2021-03-09 10:38:31,321 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] close(subscribed)
2021-03-09 10:38:31,325 [reactor-tcp-nio-2] INFO  DemoApplication - Saved >> Customer(customerId=2618b24e-ec6a-4ea9-97d7-133e91547cd0, name=Name Longer than 10 Characters)
2021-03-09 10:38:31,325 [reactor-tcp-nio-2] DEBUG FluxDiscardOnCancel - received cancel signal
2021-03-09 10:38:31,325 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneInProcToken [done=false, hasCount=true, rowCount=1, hasMore=true, currentCommand=0]
2021-03-09 10:38:31,325 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ReturnStatus [status=0]
2021-03-09 10:38:31,326 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneProcToken [done=true, hasCount=false, rowCount=0, hasMore=false, currentCommand=0]
2021-03-09 10:38:31,326 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Conversation complete

Process finished with exit code 0

And when using same code with MySQL (r2dbc-mysql)

:: Debug Log ::

2021-03-09 10:45:42,300 [main] INFO  DemoApplicationKt - Started DemoApplicationKt in 1.537 seconds (JVM running for 2.351)
2021-03-09 10:45:52,306 [main] INFO  DemoApplication - START THE TESTING >>
2021-03-09 10:45:52,409 [main] DEBUG InternalLoggerFactory - Using SLF4J as the default logging framework
2021-03-09 10:45:52,414 [main] DEBUG PlatformDependent - Platform: MacOS
2021-03-09 10:45:52,417 [main] DEBUG PlatformDependent0 - -Dio.netty.noUnsafe: false
2021-03-09 10:45:52,417 [main] DEBUG PlatformDependent0 - Java version: 15
2021-03-09 10:45:52,419 [main] DEBUG PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
2021-03-09 10:45:52,419 [main] DEBUG PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
2021-03-09 10:45:52,419 [main] DEBUG PlatformDependent0 - java.nio.Buffer.address: available
2021-03-09 10:45:52,421 [main] DEBUG PlatformDependent0 - direct buffer constructor: unavailable
...
2021-03-09 10:45:52,422 [main] DEBUG PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable
2021-03-09 10:45:52,422 [main] DEBUG PlatformDependent - sun.misc.Unsafe: available
2021-03-09 10:45:52,423 [main] DEBUG PlatformDependent - maxDirectMemory: 4294967296 bytes (maybe)
2021-03-09 10:45:52,423 [main] DEBUG PlatformDependent - -Dio.netty.tmpdir: /var/folders/45/ksbnwb2n6070054nw4y3_sfm0000gp/T (java.io.tmpdir)
2021-03-09 10:45:52,423 [main] DEBUG PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
2021-03-09 10:45:52,424 [main] DEBUG PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes
2021-03-09 10:45:52,424 [main] DEBUG PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
2021-03-09 10:45:52,425 [main] DEBUG CleanerJava9 - java.nio.ByteBuffer.cleaner(): available
2021-03-09 10:45:52,425 [main] DEBUG PlatformDependent - -Dio.netty.noPreferDirect: false
2021-03-09 10:45:52,439 [main] DEBUG ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
2021-03-09 10:45:52,440 [main] DEBUG ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
2021-03-09 10:45:52,455 [main] DEBUG TcpResources - [tcp] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-tcp, daemon=true, selectCount=8, workerCount=8}
2021-03-09 10:45:52,455 [main] DEBUG TcpResources - [tcp] resources will use the default ConnectionProvider: reactor.netty.resources.DefaultPooledConnectionProvider@2db86a7c
2021-03-09 10:45:52,456 [main] DEBUG DefaultLoopIOUring - Default io_uring support : false
2021-03-09 10:45:52,464 [main] DEBUG DefaultLoopEpoll - Default Epoll support : false
2021-03-09 10:45:52,464 [main] DEBUG DefaultLoopKQueue - Default KQueue support : false
2021-03-09 10:45:52,469 [main] DEBUG MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
2021-03-09 10:45:52,484 [main] DEBUG InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2021-03-09 10:45:52,484 [main] DEBUG InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2021-03-09 10:45:52,489 [main] DEBUG NioEventLoop - -Dio.netty.noKeySetOptimization: false
2021-03-09 10:45:52,489 [main] DEBUG NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
2021-03-09 10:45:52,490 [main] DEBUG PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
2021-03-09 10:45:52,512 [main] DEBUG NetUtil - -Djava.net.preferIPv4Stack: false
2021-03-09 10:45:52,512 [main] DEBUG NetUtil - -Djava.net.preferIPv6Addresses: false
2021-03-09 10:45:52,515 [main] DEBUG NetUtilInitializations - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
2021-03-09 10:45:52,515 [main] DEBUG NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
2021-03-09 10:45:52,536 [main] DEBUG NativeLibraryLoader - -Dio.netty.native.workdir: /var/folders/45/ksbnwb2n6070054nw4y3_sfm0000gp/T (io.netty.tmpdir)
2021-03-09 10:45:52,536 [main] DEBUG NativeLibraryLoader - -Dio.netty.native.deleteLibAfterLoading: true
2021-03-09 10:45:52,536 [main] DEBUG NativeLibraryLoader - -Dio.netty.native.tryPatchShadedId: true
2021-03-09 10:45:52,595 [main] DEBUG NativeLibraryLoader - Successfully loaded the library /var/folders/45/ksbnwb2n6070054nw4y3_sfm0000gp/T/libnetty_resolver_dns_native_macos_x86_6413562752427316041326.dylib
2021-03-09 10:45:52,600 [main] DEBUG DnsServerAddressStreamProviders - io.netty.resolver.dns.macos.MacOSDnsServerAddressStreamProvider: available
2021-03-09 10:45:52,625 [main] DEBUG DefaultChannelId - -Dio.netty.processId: 21360 (auto-detected)
2021-03-09 10:45:52,630 [main] DEBUG DefaultChannelId - -Dio.netty.machineId: ac:de:48:ff:fe:00:11:22 (auto-detected)
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
2021-03-09 10:45:52,654 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2021-03-09 10:45:52,662 [main] DEBUG ByteBufUtil - -Dio.netty.allocator.type: pooled
2021-03-09 10:45:52,662 [main] DEBUG ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
2021-03-09 10:45:52,662 [main] DEBUG ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
2021-03-09 10:45:52,678 [reactor-tcp-nio-2] DEBUG TransportConfig - [id: 0x61c2e6b5] Initialized pipeline DefaultChannelPipeline{(reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-03-09 10:45:52,704 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] Connected new channel
2021-03-09 10:45:52,705 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] onStateChange([connected], SimpleConnection{channel=[id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306]})
2021-03-09 10:45:52,709 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306]}})
2021-03-09 10:45:52,724 [reactor-tcp-nio-2] DEBUG ReactorNetty - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] Added decoder [R2dbcMySqlEnvelopeSlicer] at the end of the user pipeline, full pipeline: [R2dbcMySqlEnvelopeSlicer, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-03-09 10:45:52,730 [reactor-tcp-nio-2] DEBUG ReactorNetty - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] Added decoder [R2dbcMySqlMessageDuplexCodec] at the end of the user pipeline, full pipeline: [R2dbcMySqlEnvelopeSlicer, R2dbcMySqlMessageDuplexCodec, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-03-09 10:45:52,731 [reactor-tcp-nio-2] DEBUG ReactorNetty - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] Added encoder [R2dbcMySqlSslBridgeHandler] at the beginning of the user pipeline, full pipeline: [R2dbcMySqlSslBridgeHandler, R2dbcMySqlEnvelopeSlicer, R2dbcMySqlMessageDuplexCodec, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
2021-03-09 10:45:52,733 [reactor-tcp-nio-2] DEBUG FluxReceive - [id: 0x61c2e6b5, L:/127.0.0.1:63594 - R:/127.0.0.1:3306] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2021-03-09 10:45:52,752 [reactor-tcp-nio-2] DEBUG Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
2021-03-09 10:45:52,752 [reactor-tcp-nio-2] DEBUG Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
2021-03-09 10:45:52,752 [reactor-tcp-nio-2] DEBUG Recycler - -Dio.netty.recycler.linkCapacity: 16
2021-03-09 10:45:52,752 [reactor-tcp-nio-2] DEBUG Recycler - -Dio.netty.recycler.ratio: 8
2021-03-09 10:45:52,752 [reactor-tcp-nio-2] DEBUG Recycler - -Dio.netty.recycler.delayedQueue.ratio: 8
2021-03-09 10:45:52,768 [reactor-tcp-nio-2] DEBUG AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
2021-03-09 10:45:52,768 [reactor-tcp-nio-2] DEBUG AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
2021-03-09 10:45:52,768 [reactor-tcp-nio-2] DEBUG ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@2e901bb4
2021-03-09 10:45:52,802 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Response: HandshakeV10Request{header=HandshakeHeader{protocolVersion=10, serverVersion=5.7.26, connectionId=257}, salt=REDACTED, serverCapabilities=81fff7ff, collationLow8Bits=33, serverStatuses=2, authType=mysql_native_password}
2021-03-09 10:45:52,803 [reactor-tcp-nio-2] DEBUG SslBridgeHandler - Server unsupported SSL, remove SSL bridge in pipeline
2021-03-09 10:45:52,809 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Request: HandshakeResponse41{capabilities=12ff20f, collationId=45, user='root', authentication=REDACTED, authType='mysql_native_password', database='selfinquiry', attributes={}}
2021-03-09 10:45:52,821 [reactor-tcp-nio-2] DEBUG MessageDuplexCodec - Decode context change to DecodeContext-Command
2021-03-09 10:45:52,858 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Request: SimpleQueryMessage{sql=REDACTED}
2021-03-09 10:45:52,866 [reactor-tcp-nio-2] DEBUG MessageDuplexCodec - Decode context change to DecodeContext-Result
2021-03-09 10:45:52,867 [reactor-tcp-nio-2] DEBUG MetadataDecodeContext - Respond a metadata bundle by filled-up
2021-03-09 10:45:52,867 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Response: SyntheticMetadataMessage{completed=false, messages=[DefinitionMetadataMessage{database='', table='' (origin:''), column='i' (origin:''), collationId=45, size=60, type=253, definitions=0, decimals=31}, DefinitionMetadataMessage{database='', table='' (origin:''), column='v' (origin:''), collationId=45, size=112, type=253, definitions=0, decimals=31}, ...more 2 messages], eof=null}
2021-03-09 10:45:52,872 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Response: RowMessage(encoded)
2021-03-09 10:45:52,875 [reactor-tcp-nio-2] DEBUG MessageDuplexCodec - Decode context change to DecodeContext-Command
2021-03-09 10:45:52,875 [reactor-tcp-nio-2] DEBUG MySqlConnection - Set server time zone to +07:00 from init query
2021-03-09 10:45:52,875 [reactor-tcp-nio-2] DEBUG MySqlConnection - Batch is supported by server
2021-03-09 10:45:52,877 [reactor-tcp-nio-2] DEBUG DefaultDatabaseClient - Executing SQL statement [INSERT INTO customer (customer_id, name) VALUES (?, ?)]
2021-03-09 10:45:52,877 [reactor-tcp-nio-2] DEBUG MySqlConnection - Create a parametrized statement provided by text query
2021-03-09 10:45:52,883 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Request: TextQueryMessage{sqlParts=REDACTED, values=REDACTED}
2021-03-09 10:45:52,890 [reactor-tcp-nio-2] DEBUG MessageDuplexCodec - Decode context change to DecodeContext-Command
2021-03-09 10:45:52,890 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Response: ErrorMessage{errorCode=1406, sqlState='22001', errorMessage='Data too long for column 'name' at row 1'}
2021-03-09 10:45:52,903 [reactor-tcp-nio-2] DEBUG MySqlConnection - Connection closing
2021-03-09 10:45:52,903 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - Request: ExitMessage{}
2021-03-09 10:45:52,905 [reactor-tcp-nio-2] DEBUG ReactorNetty - [id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306] Non Removed handler: R2dbcMySqlEnvelopeSlicer, context: ChannelHandlerContext(R2dbcMySqlEnvelopeSlicer, [id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306]), pipeline: DefaultChannelPipeline{(R2dbcMySqlEnvelopeSlicer = dev.miku.r2dbc.mysql.client.EnvelopeSlicer), (R2dbcMySqlMessageDuplexCodec = dev.miku.r2dbc.mysql.client.MessageDuplexCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-03-09 10:45:52,905 [reactor-tcp-nio-2] DEBUG ReactorNetty - [id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306] Non Removed handler: R2dbcMySqlMessageDuplexCodec, context: ChannelHandlerContext(R2dbcMySqlMessageDuplexCodec, [id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306]), pipeline: DefaultChannelPipeline{(R2dbcMySqlEnvelopeSlicer = dev.miku.r2dbc.mysql.client.EnvelopeSlicer), (R2dbcMySqlMessageDuplexCodec = dev.miku.r2dbc.mysql.client.MessageDuplexCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-03-09 10:45:52,905 [reactor-tcp-nio-2] DEBUG ReactorNetty - [id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306] Non Removed handler: R2dbcMySqlSslBridgeHandler, context: null, pipeline: DefaultChannelPipeline{(R2dbcMySqlEnvelopeSlicer = dev.miku.r2dbc.mysql.client.EnvelopeSlicer), (R2dbcMySqlMessageDuplexCodec = dev.miku.r2dbc.mysql.client.MessageDuplexCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-03-09 10:45:52,905 [reactor-tcp-nio-2] DEBUG MySqlConnection - Connection close succeed
2021-03-09 10:45:52,908 [reactor-tcp-nio-2] ERROR DemoApplication - Got an error >> executeMany; SQL [INSERT INTO customer (customer_id, name) VALUES (?, ?)]; Data too long for column 'name' at row 1; nested exception is io.r2dbc.spi.R2dbcNonTransientResourceException: [1406] Data too long for column 'name' at row 1
org.springframework.dao.DataAccessResourceFailureException: executeMany; SQL [INSERT INTO customer (customer_id, name) VALUES (?, ?)]; Data too long for column 'name' at row 1; nested exception is io.r2dbc.spi.R2dbcNonTransientResourceException: [1406] Data too long for column 'name' at row 1
	at org.springframework.r2dbc.connection.ConnectionFactoryUtils.convertR2dbcException(ConnectionFactoryUtils.java:226)
	at org.springframework.r2dbc.core.DefaultDatabaseClient.lambda$inConnectionMany$8(DefaultDatabaseClient.java:147)
	at reactor.core.publisher.Flux.lambda$onErrorMap$28(Flux.java:6641)
	at reactor.core.publisher.Flux.lambda$onErrorResume$29(Flux.java:6694)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:94)
	at reactor.core.publisher.FluxUsingWhen$UsingWhenSubscriber.deferredError(FluxUsingWhen.java:411)
	at reactor.core.publisher.FluxUsingWhen$RollbackInner.onComplete(FluxUsingWhen.java:488)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete(MonoPeekTerminal.java:299)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onComplete(FluxPeekFuseable.java:595)
	at reactor.core.publisher.Operators$MonoSubscriber.onComplete(Operators.java:1857)
	at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onComplete(MonoIgnoreThen.java:323)
	at reactor.core.publisher.Operators.complete(Operators.java:136)
	at reactor.netty.FutureMono$DeferredFutureMono.subscribe(FutureMono.java:131)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:154)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.ignoreDone(MonoIgnoreThen.java:191)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreInner.onComplete(MonoIgnoreThen.java:248)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:148)
	at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:160)
	at dev.miku.r2dbc.mysql.client.RequestTask.run(RequestTask.java:46)
	at dev.miku.r2dbc.mysql.client.RequestQueue.run(RequestQueue.java:79)
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onComplete(FluxPeekFuseable.java:945)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onComplete(MonoFlatMapMany.java:260)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:259)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onComplete(FluxHandle.java:212)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:133)
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
	at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
	at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
	at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:265)
	at dev.miku.r2dbc.mysql.client.ReactorNettyClient$ResponseSink.next(ReactorNettyClient.java:340)
	at dev.miku.r2dbc.mysql.client.ReactorNettyClient.lambda$new$0(ReactorNettyClient.java:103)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:184)
	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:267)
	at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:377)
	at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:381)
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.handleDecoded(MessageDuplexCodec.java:187)
	at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.channelRead(MessageDuplexCodec.java:95)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:832)
Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Data too long for column 'name' at row 1
	at dev.miku.r2dbc.mysql.ExceptionFactory.mappingSqlState(ExceptionFactory.java:115)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint ⇢ SQL "INSERT INTO customer (customer_id, name) VALUES (?, ?)" [DatabaseClient]
Stack trace:
		at dev.miku.r2dbc.mysql.ExceptionFactory.mappingSqlState(ExceptionFactory.java:115)
		at dev.miku.r2dbc.mysql.ExceptionFactory.createException(ExceptionFactory.java:102)
		at dev.miku.r2dbc.mysql.TextQueryHandler.accept(QueryFlow.java:317)
		at dev.miku.r2dbc.mysql.TextQueryHandler.accept(QueryFlow.java:292)
		at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:169)
		at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
		at dev.miku.r2dbc.mysql.util.DiscardOnCancelSubscriber.onNext(DiscardOnCancelSubscriber.java:70)
		at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
		at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:250)
		at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:199)
		at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:118)
		at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
		at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
		at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
		at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
		at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:265)
		at dev.miku.r2dbc.mysql.client.ReactorNettyClient$ResponseSink.next(ReactorNettyClient.java:340)
		at dev.miku.r2dbc.mysql.client.ReactorNettyClient.lambda$new$0(ReactorNettyClient.java:103)
		at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:184)
		at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:267)
		at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:377)
		at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:381)
		at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.handleDecoded(MessageDuplexCodec.java:187)
		at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.channelRead(MessageDuplexCodec.java:95)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
		at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
		at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
		at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
		at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
		at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
		at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
		at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
		at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
		at java.base/java.lang.Thread.run(Thread.java:832)
2021-03-09 10:45:52,911 [reactor-tcp-nio-2] DEBUG NewConnectionProvider - [id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306] onStateChange([disconnecting], ChannelOperations{SimpleConnection{channel=[id: 0x61c2e6b5, L:/127.0.0.1:63594 ! R:/127.0.0.1:3306]}})
...
2021-03-09 10:45:52,953 [main] ERROR SpringApplication - Application run failed
java.lang.IllegalStateException: Failed to execute CommandLineRunner
	at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:802)
	at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:783)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:335)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1314)
	at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303)
	at com.example.demo.DemoApplicationKt.main(DemoApplication.kt:51)
Caused by: org.springframework.dao.DataAccessResourceFailureException: executeMany; SQL [INSERT INTO customer (customer_id, name) VALUES (?, ?)]; Data too long for column 'name' at row 1; nested exception is io.r2dbc.spi.R2dbcNonTransientResourceException: [1406] Data too long for column 'name' at row 1
	at org.springframework.r2dbc.connection.ConnectionFactoryUtils.convertR2dbcException(ConnectionFactoryUtils.java:226)
	at org.springframework.r2dbc.core.DefaultDatabaseClient.lambda$inConnectionMany$8(DefaultDatabaseClient.java:147)
	at reactor.core.publisher.Flux.lambda$onErrorMap$28(Flux.java:6641)
	at reactor.core.publisher.Flux.lambda$onErrorResume$29(Flux.java:6694)
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onError(FluxOnErrorResume.java:94)
	at reactor.core.publisher.FluxUsingWhen$UsingWhenSubscriber.deferredError(FluxUsingWhen.java:411)
	at reactor.core.publisher.FluxUsingWhen$RollbackInner.onComplete(FluxUsingWhen.java:488)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.onComplete(MonoPeekTerminal.java:299)
	at reactor.core.publisher.FluxPeekFuseable$PeekFuseableConditionalSubscriber.onComplete(FluxPeekFuseable.java:595)
	at reactor.core.publisher.Operators$MonoSubscriber.onComplete(Operators.java:1857)
	at reactor.core.publisher.MonoIgnoreThen$ThenAcceptInner.onComplete(MonoIgnoreThen.java:323)
	at reactor.core.publisher.Operators.complete(Operators.java:136)
	at reactor.netty.FutureMono$DeferredFutureMono.subscribe(FutureMono.java:131)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.drain(MonoIgnoreThen.java:154)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.ignoreDone(MonoIgnoreThen.java:191)
	at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreInner.onComplete(MonoIgnoreThen.java:248)
	at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.onComplete(Operators.java:2057)
	at reactor.core.publisher.MonoFlatMap$FlatMapMain.onNext(MonoFlatMap.java:148)
	at reactor.core.publisher.MonoCreate$DefaultMonoSink.success(MonoCreate.java:160)
	at dev.miku.r2dbc.mysql.client.RequestTask.run(RequestTask.java:46)
	at dev.miku.r2dbc.mysql.client.RequestQueue.run(RequestQueue.java:79)
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onComplete(FluxPeekFuseable.java:945)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onComplete(MonoFlatMapMany.java:260)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:259)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onComplete(FluxHandle.java:212)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:133)
	at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
	at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
	at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
	at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:265)
	at dev.miku.r2dbc.mysql.client.ReactorNettyClient$ResponseSink.next(ReactorNettyClient.java:340)
	at dev.miku.r2dbc.mysql.client.ReactorNettyClient.lambda$new$0(ReactorNettyClient.java:103)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:184)
	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:267)
	at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:377)
	at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:381)
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.handleDecoded(MessageDuplexCodec.java:187)
	at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.channelRead(MessageDuplexCodec.java:95)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:832)
	Suppressed: java.lang.Exception: #block terminated with an error
		at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:99)
		at reactor.core.publisher.Mono.block(Mono.java:1703)
		at com.example.demo.DemoApplication$demo$1.run(DemoApplication.kt:32)
		at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:799)
		at org.springframework.boot.SpringApplication.callRunners(SpringApplication.java:783)
		at org.springframework.boot.SpringApplication.run(SpringApplication.java:335)
		at org.springframework.boot.SpringApplication.run(SpringApplication.java:1314)
		at org.springframework.boot.SpringApplication.run(SpringApplication.java:1303)
		at com.example.demo.DemoApplicationKt.main(DemoApplication.kt:51)
Caused by: io.r2dbc.spi.R2dbcNonTransientResourceException: Data too long for column 'name' at row 1
	at dev.miku.r2dbc.mysql.ExceptionFactory.mappingSqlState(ExceptionFactory.java:115)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint ⇢ SQL "INSERT INTO customer (customer_id, name) VALUES (?, ?)" [DatabaseClient]
Stack trace:
		at dev.miku.r2dbc.mysql.ExceptionFactory.mappingSqlState(ExceptionFactory.java:115)
		at dev.miku.r2dbc.mysql.ExceptionFactory.createException(ExceptionFactory.java:102)
		at dev.miku.r2dbc.mysql.TextQueryHandler.accept(QueryFlow.java:317)
		at dev.miku.r2dbc.mysql.TextQueryHandler.accept(QueryFlow.java:292)
		at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:169)
		at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.onNext(FluxContextWrite.java:107)
		at dev.miku.r2dbc.mysql.util.DiscardOnCancelSubscriber.onNext(DiscardOnCancelSubscriber.java:70)
		at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
		at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:250)
		at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:199)
		at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:118)
		at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.onNext(FluxPeekFuseable.java:854)
		at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:491)
		at reactor.core.publisher.EmitterProcessor.tryEmitNext(EmitterProcessor.java:299)
		at reactor.core.publisher.InternalManySink.emitNext(InternalManySink.java:27)
		at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:265)
		at dev.miku.r2dbc.mysql.client.ReactorNettyClient$ResponseSink.next(ReactorNettyClient.java:340)
		at dev.miku.r2dbc.mysql.client.ReactorNettyClient.lambda$new$0(ReactorNettyClient.java:103)
		at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:184)
		at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:267)
		at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:377)
		at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:381)
		at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.handleDecoded(MessageDuplexCodec.java:187)
		at dev.miku.r2dbc.mysql.client.MessageDuplexCodec.channelRead(MessageDuplexCodec.java:95)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
		at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
		at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
		at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
		at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
		at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
		at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
		at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
		at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
		at java.base/java.lang.Thread.run(Thread.java:832)
2021-03-09 10:45:52,954 [main] DEBUG AnnotationConfigApplicationContext - Closing org.springframework.context.annotation.AnnotationConfigApplicationContext@a4ca3f6, started on Tue Mar 09 10:45:41 ICT 2021
2021-03-09 10:45:52,954 [main] DEBUG PropertySourcesPropertyResolver - Found key 'spring.liveBeansView.mbeanDomain' in PropertySource 'systemProperties' with value of type String
2021-03-09 10:45:52,956 [main] DEBUG AnnotationMBeanExporter - Unregistering JMX-exposed beans on shutdown

Process finished with exit code 1

The exception thrown as expected.

The repository to replicate the issue is https://github.com/niciosity/test-spring-data-r2dbc

Please investigate, Thank you very much.

@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged label Mar 9, 2021
@niciosity
Copy link
Author

Test the insert using standalone r2dbc-mssql driver is working fine as expected.
The repository to replicate the issue is https://github.com/niciosity/test-r2dbc-mssql

:: Debug Log::

/usr/local/Cellar/openjdk/15.0.1/libexec/openjdk.jdk/Contents/Home/bin/java -javaagent:/Applications/IntelliJ IDEA.app/Contents/lib/idea_rt.jar=63834:/Applications/IntelliJ IDEA.app/Contents/bin -Dfile.encoding=UTF-8 -classpath /Users/Tanawas.R/Downloads/test-r2dbc-mssql/build/classes/kotlin/main:/Users/Tanawas.R/Downloads/test-r2dbc-mssql/build/resources/main:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib-jdk8/1.4.31/e613be5465ef1e6fd0468707690b7ebf625ea2fe/kotlin-stdlib-jdk8-1.4.31.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-reflect/1.4.31/63db9d66c3d20f7b8f66196e7ba86969daae8b8a/kotlin-reflect-1.4.31.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.r2dbc/r2dbc-mssql/0.8.5.RELEASE/b2ab159e31337f2700b087bb888e6ce0027ecc40/r2dbc-mssql-0.8.5.RELEASE.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/ch.qos.logback/logback-classic/1.2.3/7c4f3c474fb2c041d8028740440937705ebb473a/logback-classic-1.2.3.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/net.logstash.logback/logstash-logback-encoder/6.4/6b34287e15e40ba8dc79e8bbe1f09815431ae3f6/logstash-logback-encoder-6.4.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib-jdk7/1.4.31/84ce8e85f6e84270b2b501d44e9f0ba6ff64fa71/kotlin-stdlib-jdk7-1.4.31.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib/1.4.31/a58e0fb9812a6a93ca24b5da75e4b5a0cb89c957/kotlin-stdlib-1.4.31.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.r2dbc/r2dbc-spi/0.8.3.RELEASE/377d9e71c6cd1e2c2c5b67e1412c0965de5e954f/r2dbc-spi-0.8.3.RELEASE.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.projectreactor.netty/reactor-netty/0.9.12.RELEASE/41022546d07f1499fb9d8617bba4a1a89d3549db/reactor-netty-0.9.12.RELEASE.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.projectreactor/reactor-core/3.3.10.RELEASE/f5787f994a9a810c0986418232e06fcf4afc1216/reactor-core-3.3.10.RELEASE.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/ch.qos.logback/logback-core/1.2.3/864344400c3d4d92dfeb0a305dc87d953677c03c/logback-core-1.2.3.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.slf4j/slf4j-api/1.7.25/da76ca59f6a57ee3102f8f9bd9cee742973efa8a/slf4j-api-1.7.25.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/com.fasterxml.jackson.core/jackson-databind/2.11.0/8f5aaf3878b0647ff3a16610af53b1a5c05d9f15/jackson-databind-2.11.0.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.jetbrains.kotlin/kotlin-stdlib-common/1.4.31/6dd50665802f54ba9bc3f70ecb20227d1bc81323/kotlin-stdlib-common-1.4.31.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.jetbrains/annotations/13.0/919f0dfe192fb4e063e7dacadee7f8bb9a2672a9/annotations-13.0.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/org.reactivestreams/reactive-streams/1.0.3/d9fb7a7926ffa635b3dcaa5049fb2bfa25b3e7d0/reactive-streams-1.0.3.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-codec-http2/4.1.52.Final/1e06a41e2b67cd6f91bf97935f4729c843ac1a57/netty-codec-http2-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-handler-proxy/4.1.52.Final/e5701741e851d83b5ef15738f84c825ba2c0688e/netty-handler-proxy-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-codec-http/4.1.52.Final/e0d75d03edf6e4d0682c85e8b26762bcde34697d/netty-codec-http-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-handler/4.1.52.Final/eb7d4fa554f4fdc8dacb80dce7e3f806fd1dc2db/netty-handler-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-transport-native-epoll/4.1.52.Final/5cfac181f741082a1e69ceecdf11e379abb0d136/netty-transport-native-epoll-4.1.52.Final-linux-x86_64.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/com.fasterxml.jackson.core/jackson-annotations/2.11.0/c626020ae55d19c690d25cb51c1532ba76e5890f/jackson-annotations-2.11.0.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/com.fasterxml.jackson.core/jackson-core/2.11.0/f84302e14648f9f63c0c73951054aeb2ff0b810a/jackson-core-2.11.0.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-codec/4.1.52.Final/d98ad5bb86707c3c1a7105a346119dac332bdf23/netty-codec-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-transport/4.1.52.Final/970ee3790f504452bd32692f6b208a590c51f0ee/netty-transport-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-buffer/4.1.52.Final/fdf681985f50d84fac625df52f34b6d6cb699bda/netty-buffer-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-common/4.1.52.Final/715bfadb9f3bf86da38fa12b97b4aaa9828b4789/netty-common-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-codec-socks/4.1.52.Final/93170f664ae83ec70c35752b91cb733f9b80bf90/netty-codec-socks-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-resolver/4.1.52.Final/1fd5a58ff5df4dc9bb3027a6fbf114767d9278d5/netty-resolver-4.1.52.Final.jar:/Users/Tanawas.R/.gradle/caches/modules-2/files-2.1/io.netty/netty-transport-native-unix-common/4.1.52.Final/bec4d7135ae82ab1f90938bb6625e43b4b15e165/netty-transport-native-unix-common-4.1.52.Final.jar com.example.MsSqlAppKt
START THE TESTING >>
2021-03-09 11:06:02,979 [main] DEBUG Loggers$LoggerFactory - Using Slf4j logging framework
2021-03-09 11:06:03,088 [main] DEBUG MssqlConnectionFactoryProvider - Creating MssqlConnectionFactory with configuration [MssqlConnectionConfiguration [applicationName="null", connectionId=c4eda314-c2b6-438d-9256-46026e5fdd55, connectTimeout="PT30S", database="selfinquiry", host="localhost", hostNameInCertificate="localhost", password="*****", preferCursoredExecution="io.r2dbc.mssql.MssqlConnectionConfiguration$Builder$$Lambda$62/0x0000000800c32928@3943a2be", port=1433, sendStringParametersAsUnicode=true, ssl=false, sslContextBuilderCustomizer=java.util.function.Function$$Lambda$63/0x0000000800c3c2b8@343570b7, sslTunnelSslContextBuilderCustomizer=null, tcpKeepAlive="false", tcpNoDelay="true", trustStore="null", trustStorePassword="", trustStoreType="null", username="sa"]] from options [ConnectionFactoryOptions{options={database=selfinquiry, host=localhost, driver=sqlserver, password=REDACTED, port=1433, user=sa}}]
2021-03-09 11:06:03,156 [main] DEBUG InternalLoggerFactory - Using SLF4J as the default logging framework
2021-03-09 11:06:03,164 [main] DEBUG InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2021-03-09 11:06:03,164 [main] DEBUG InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2021-03-09 11:06:03,201 [main] DEBUG PlatformDependent - Platform: MacOS
2021-03-09 11:06:03,203 [main] DEBUG PlatformDependent0 - -Dio.netty.noUnsafe: false
2021-03-09 11:06:03,203 [main] DEBUG PlatformDependent0 - Java version: 15
2021-03-09 11:06:03,207 [main] DEBUG PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
2021-03-09 11:06:03,208 [main] DEBUG PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
2021-03-09 11:06:03,210 [main] DEBUG PlatformDependent0 - java.nio.Buffer.address: available
2021-03-09 11:06:03,216 [main] DEBUG PlatformDependent0 - direct buffer constructor: unavailable
...
2021-03-09 11:06:03,221 [main] DEBUG PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable
2021-03-09 11:06:03,221 [main] DEBUG PlatformDependent - sun.misc.Unsafe: available
2021-03-09 11:06:03,247 [main] DEBUG PlatformDependent - maxDirectMemory: 4294967296 bytes (maybe)
2021-03-09 11:06:03,248 [main] DEBUG PlatformDependent - -Dio.netty.tmpdir: /var/folders/45/ksbnwb2n6070054nw4y3_sfm0000gp/T (java.io.tmpdir)
2021-03-09 11:06:03,248 [main] DEBUG PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
2021-03-09 11:06:03,249 [main] DEBUG PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes
2021-03-09 11:06:03,249 [main] DEBUG PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
2021-03-09 11:06:03,250 [main] DEBUG CleanerJava9 - java.nio.ByteBuffer.cleaner(): available
2021-03-09 11:06:03,250 [main] DEBUG PlatformDependent - -Dio.netty.noPreferDirect: false
2021-03-09 11:06:03,274 [main] DEBUG ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
2021-03-09 11:06:03,275 [main] DEBUG ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
2021-03-09 11:06:03,280 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
2021-03-09 11:06:03,280 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
2021-03-09 11:06:03,280 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
2021-03-09 11:06:03,281 [main] DEBUG PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2021-03-09 11:06:03,306 [main] DEBUG ByteBufUtil - -Dio.netty.allocator.type: pooled
2021-03-09 11:06:03,306 [main] DEBUG ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
2021-03-09 11:06:03,307 [main] DEBUG ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
2021-03-09 11:06:03,313 [main] DEBUG Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
2021-03-09 11:06:03,315 [main] DEBUG Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
2021-03-09 11:06:03,315 [main] DEBUG Recycler - -Dio.netty.recycler.linkCapacity: 16
2021-03-09 11:06:03,315 [main] DEBUG Recycler - -Dio.netty.recycler.ratio: 8
2021-03-09 11:06:03,315 [main] DEBUG Recycler - -Dio.netty.recycler.delayedQueue.ratio: 8
2021-03-09 11:06:03,330 [main] DEBUG AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
2021-03-09 11:06:03,330 [main] DEBUG AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
2021-03-09 11:06:03,332 [main] DEBUG ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@5032714f
2021-03-09 11:06:04,038 [main] DEBUG ReactorNettyClient - [cid: 0x1] connect()
2021-03-09 11:06:04,159 [main] DEBUG NetUtil - -Djava.net.preferIPv4Stack: false
2021-03-09 11:06:04,164 [main] DEBUG NetUtil - -Djava.net.preferIPv6Addresses: false
2021-03-09 11:06:04,176 [main] DEBUG NetUtil - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
2021-03-09 11:06:04,177 [main] DEBUG NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
2021-03-09 11:06:04,255 [main] DEBUG TcpResources - [tcp] resources will use the default LoopResources: DefaultLoopResources {prefix=reactor-tcp, daemon=true, selectCount=8, workerCount=8}
2021-03-09 11:06:04,255 [main] DEBUG TcpResources - [tcp] resources will use the default ConnectionProvider: reactor.netty.resources.PooledConnectionProvider@6581dc0a
2021-03-09 11:06:04,258 [main] DEBUG DefaultLoopKQueue - Default KQueue support : false
2021-03-09 11:06:04,287 [main] DEBUG DefaultLoopEpoll - Default Epoll support : false
2021-03-09 11:06:04,321 [main] DEBUG MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
2021-03-09 11:06:04,358 [main] DEBUG NioEventLoop - -Dio.netty.noKeySetOptimization: false
2021-03-09 11:06:04,358 [main] DEBUG NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
2021-03-09 11:06:04,375 [main] DEBUG PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
2021-03-09 11:06:04,454 [main] DEBUG DefaultChannelId - -Dio.netty.processId: 21758 (auto-detected)
2021-03-09 11:06:04,463 [main] DEBUG DefaultChannelId - -Dio.netty.machineId: ac:de:48:ff:fe:00:11:22 (auto-detected)
2021-03-09 11:06:04,587 [reactor-tcp-nio-1] DEBUG BootstrapHandlers - [id: 0x2d389bee] Initialized pipeline DefaultChannelPipeline{(BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2021-03-09 11:06:04,611 [reactor-tcp-nio-1] DEBUG NewConnectionProvider - [id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433] Connected new channel
2021-03-09 11:06:04,612 [reactor-tcp-nio-1] DEBUG NewConnectionProvider - [id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433] onStateChange([connected], SimpleConnection{channel=[id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433]})
2021-03-09 11:06:04,616 [reactor-tcp-nio-1] DEBUG NewConnectionProvider - [id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433] onStateChange([configured], ChannelOperations{SimpleConnection{channel=[id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433]}})
2021-03-09 11:06:04,681 [reactor-tcp-nio-1] DEBUG FluxReceive - [id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
2021-03-09 11:06:04,700 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] exchange()
2021-03-09 11:06:04,714 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] exchange(subscribed)
2021-03-09 11:06:04,717 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Initiating exchange
2021-03-09 11:06:04,722 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Request: PRELOGIN [tokens=[Version [version=0, subbuild=0], Encryption [encryption=0], InstanceValidation [instanceName=MSSQLServer�], TraceId [connectionId=c4eda314-c2b6-438d-9256-46026e5fdd55, activityId=null, activitySequence=0], Terminator []]]
2021-03-09 11:06:04,753 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: PRELOGIN [tokens=[Version [version=14, subbuild=3356], Encryption [encryption=0], InstanceValidation [instanceName=�], UnknownToken, Terminator []]]
2021-03-09 11:06:05,029 [reactor-tcp-nio-1] DEBUG OpenSsl - netty-tcnative not in the classpath; OpenSslEngine will be unavailable.
2021-03-09 11:06:05,333 [reactor-tcp-nio-1] DEBUG SslUtils - JDK SSLEngine supports TLSv1.3: true
2021-03-09 11:06:05,335 [reactor-tcp-nio-1] DEBUG JdkSslContext - Default protocols (JDK): [TLSv1.3, TLSv1.2, TLSv1.1, TLSv1] 
2021-03-09 11:06:05,336 [reactor-tcp-nio-1] DEBUG JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_AES_128_GCM_SHA256, TLS_AES_256_GCM_SHA384]
2021-03-09 11:06:05,361 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Registering Context Proxy and SSL Event Handlers to propagate SSL events to channelRead()
2021-03-09 11:06:05,460 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 11:06:05,463 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Flushing output buffer and enable auto-read
2021-03-09 11:06:05,571 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 11:06:05,572 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 11:06:05,573 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Append to output buffer
2021-03-09 11:06:05,574 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] Write wrapping: Flushing output buffer and enable auto-read
2021-03-09 11:06:05,587 [reactor-tcp-nio-1] DEBUG SslHandler - [id: 0x2d389bee, L:/127.0.0.1:63836 - R:localhost/127.0.0.1:1433] HANDSHAKEN: protocol:TLSv1.2 cipher suite:TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2021-03-09 11:06:05,587 [reactor-tcp-nio-1] DEBUG TdsSslHandler - [cid: 0x1] SSL Handshake done
2021-03-09 11:06:05,588 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: NEGOTIATED
2021-03-09 11:06:05,608 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Request: Login7 [header=DefaultHeaderOptions [type=TDS7_LOGIN, status=0], tdsVersion=VER_DENALI, packetSize=8000, clientPid=0, connectionId=0, tokens=[LoginRequestToken [tokenType=Hostname], LoginRequestToken [tokenType=Username], LoginRequestToken [tokenType=Password], LoginRequestToken [tokenType=AppName], LoginRequestToken [tokenType=Servername], LoginRequestToken [tokenType=IntName], LoginRequestToken [tokenType=Database]]]
2021-03-09 11:06:05,647 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=37, changeType=Database, newValue=selfinquiry]
2021-03-09 11:06:05,648 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: InfoToken [number=5701, state=2, infoClass=0, message='Changed database context to 'selfinquiry'.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 11:06:05,648 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Info: Code [5701] Severity [INFORMATIONAL]: Changed database context to 'selfinquiry'.
2021-03-09 11:06:05,648 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=8, changeType=SQLCollation, newValue=ОÐ�]
2021-03-09 11:06:05,674 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=23, changeType=Language, newValue=us_english]
2021-03-09 11:06:05,675 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: InfoToken [number=5703, state=1, infoClass=0, message='Changed language setting to us_english.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 11:06:05,675 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Info: Code [5703] Severity [INFORMATIONAL]: Changed language setting to us_english.
2021-03-09 11:06:05,676 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: LoginAckToken [clientInterface=1, tdsVersion=1946157060, progrName='Microsoft SQL Server��", version=14.00.3356]
2021-03-09 11:06:05,677 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ENVCHANGE_TOKEN [length=19, changeType=Packetsize, newValue=8000]
2021-03-09 11:06:05,677 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: FeatureExtAckToken [featureTokens=[ColumnEncryption [tceVersion=1]]]
2021-03-09 11:06:05,677 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneToken [done=true, hasCount=false, rowCount=0, hasMore=false, currentCommand=0]
2021-03-09 11:06:05,694 [reactor-tcp-nio-1] DEBUG SimpleMssqlStatement - [cid: 0x1] Start direct exchange for  SELECT CAST(SERVERPROPERTY('Edition') AS VARCHAR(255)) AS Edition, CAST(@@VERSION AS VARCHAR(255)) as VersionString
2021-03-09 11:06:05,696 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] exchange()
2021-03-09 11:06:05,708 [reactor-tcp-nio-1] DEBUG QUERY - [cid: 0x1] Executing query:  SELECT CAST(SERVERPROPERTY('Edition') AS VARCHAR(255)) AS Edition, CAST(@@VERSION AS VARCHAR(255)) as VersionString
2021-03-09 11:06:05,708 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] exchange(subscribed)
2021-03-09 11:06:05,708 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Queueing exchange
2021-03-09 11:06:05,708 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Initiating queued exchange
2021-03-09 11:06:05,709 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Request: SQLBatch [sql=" SELECT CAST(SERVERPROPERTY('Edition') AS VARCHAR(255)) AS Edition, CAST(@@VERSION AS VARCHAR(255)) as VersionString"]
2021-03-09 11:06:05,724 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ColumnMetadataToken [columns=[Column [name='Edition", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null], Column [name='VersionString", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null]]]
2021-03-09 11:06:05,725 [reactor-tcp-nio-1] DEBUG MssqlResult - [cid: 0x1] Creating new result
2021-03-09 11:06:05,730 [reactor-tcp-nio-1] DEBUG MssqlResult - [cid: 0x1] Result column definition: ColumnMetadataToken [columns=[Column [name='Edition", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null], Column [name='VersionString", type=MutableTypeInformation [maxLength=255, lengthStrategy=USHORTLENTYPE, precision=255, displaySize=255, scale=0, flags=33, serverType=varchar, userType=0, udtTypeName="null", collation=Collation [encoding=CP874], charset=x-windows-874], table=null]]]
2021-03-09 11:06:05,736 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: io.r2dbc.mssql.message.token.RowToken@29fd3bdb
2021-03-09 11:06:05,739 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneToken [done=true, hasCount=true, rowCount=1, hasMore=false, currentCommand=0]
2021-03-09 11:06:05,740 [reactor-tcp-nio-1] DEBUG MssqlConnection - [cid: 0x1] Creating statement for SQL: [insert into customer (customer_id, name) values (@id, @name)]
2021-03-09 11:06:05,755 [reactor-tcp-nio-1] DEBUG ParametrizedMssqlStatement - [cid: 0x1] Start direct exchange for insert into customer (customer_id, name) values (@id, @name)
2021-03-09 11:06:05,763 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] exchange()
2021-03-09 11:06:05,767 [reactor-tcp-nio-1] DEBUG MssqlResult - [cid: 0x1] Creating new result
Row Updated : MonoMapFuseable
2021-03-09 11:06:05,772 [reactor-tcp-nio-1] DEBUG QUERY - [cid: 0x1] Executing query: insert into customer (customer_id, name) values (@id, @name)
2021-03-09 11:06:05,774 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] exchange(subscribed)
2021-03-09 11:06:05,774 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Queueing exchange
2021-03-09 11:06:05,774 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Initiating queued exchange
2021-03-09 11:06:05,777 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Request: RPCRequest [procName='null', procId=10, optionFlags=io.r2dbc.mssql.message.token.RpcRequest$OptionFlags@741bbee, statusFlags=0, parameterDescriptors=[RpcString [name='null', value=insert into customer (customer_id, name) values (@id, @name)], RpcString [name='null', value=@id nvarchar(4000),@name nvarchar(4000)], EncodedRpcParameter [name='id', value=io.r2dbc.mssql.codec.CharacterEncoder$NvarcharEncoded@2042cbf1], EncodedRpcParameter [name='name', value=io.r2dbc.mssql.codec.CharacterEncoder$NvarcharEncoded@66d67cf4]]]
2021-03-09 11:06:05,807 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ErrorToken [number=8152, state=30, infoClass=16, message='String or binary data would be truncated.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 11:06:05,808 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Warning: Code [8152] Severity [GENERAL_ERROR]: String or binary data would be truncated.
2021-03-09 11:06:05,816 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: InfoToken [number=3621, state=0, infoClass=0, message='The statement has been terminated.", serverName='f9ab3957f09e", procName='", lineNumber=16777216]
2021-03-09 11:06:05,816 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Info: Code [3621] Severity [INFORMATIONAL]: The statement has been terminated.
2021-03-09 11:06:05,817 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneInProcToken [done=false, hasCount=false, rowCount=0, hasMore=true, currentCommand=195]
2021-03-09 11:06:05,818 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: ReturnStatus [status=8152]
2021-03-09 11:06:05,818 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Response: DoneProcToken [done=true, hasCount=false, rowCount=0, hasMore=false, currentCommand=0]
2021-03-09 11:06:05,821 [reactor-tcp-nio-1] DEBUG FluxDiscardOnCancel - received cancel signal
Got error >>> String or binary data would be truncated.
2021-03-09 11:06:05,824 [reactor-tcp-nio-1] DEBUG ReactorNettyClient - [cid: 0x1] Conversation complete
io.r2dbc.mssql.ExceptionFactory$MssqlNonTransientException: [8152] [22001] String or binary data would be truncated.
	at io.r2dbc.mssql.ExceptionFactory.createException(ExceptionFactory.java:152)
	at io.r2dbc.mssql.MssqlResult.lambda$getRowsUpdated$0(MssqlResult.java:112)
	at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:163)
	at reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onNext(FluxContextStart.java:96)
	at io.r2dbc.mssql.util.FluxDiscardOnCancel$FluxDiscardOnCancelSubscriber.onNext(FluxDiscardOnCancel.java:89)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxFilter$FilterSubscriber.onNext(FluxFilter.java:107)
	at reactor.core.publisher.FluxHandle$HandleConditionalSubscriber.onNext(FluxHandle.java:319)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:432)
	at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:274)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:112)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:242)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:432)
	at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:274)
	at io.r2dbc.mssql.client.ReactorNettyClient$1.next(ReactorNettyClient.java:244)
	at io.r2dbc.mssql.client.ReactorNettyClient$1.next(ReactorNettyClient.java:204)
	at io.r2dbc.mssql.message.token.Tabular$TabularDecoder.decode(Tabular.java:424)
	at io.r2dbc.mssql.client.ConnectionState$4$1.decode(ConnectionState.java:206)
	at io.r2dbc.mssql.client.StreamDecoder.withState(StreamDecoder.java:137)
	at io.r2dbc.mssql.client.StreamDecoder.decode(StreamDecoder.java:109)
	at io.r2dbc.mssql.client.ReactorNettyClient.lambda$new$6(ReactorNettyClient.java:254)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:177)
	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:256)
	at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:362)
	at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:358)
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:96)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
	at io.r2dbc.mssql.client.ssl.TdsSslHandler.channelRead(TdsSslHandler.java:380)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:832)
Exception in thread "main" io.r2dbc.mssql.ExceptionFactory$MssqlNonTransientException: [8152] [22001] String or binary data would be truncated.
	at io.r2dbc.mssql.ExceptionFactory.createException(ExceptionFactory.java:152)
	at io.r2dbc.mssql.MssqlResult.lambda$getRowsUpdated$0(MssqlResult.java:112)
	at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:163)
	at reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onNext(FluxContextStart.java:96)
	at io.r2dbc.mssql.util.FluxDiscardOnCancel$FluxDiscardOnCancelSubscriber.onNext(FluxDiscardOnCancel.java:89)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxFilter$FilterSubscriber.onNext(FluxFilter.java:107)
	at reactor.core.publisher.FluxHandle$HandleConditionalSubscriber.onNext(FluxHandle.java:319)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:432)
	at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:274)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:112)
	at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:242)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
	at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:432)
	at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:274)
	at io.r2dbc.mssql.client.ReactorNettyClient$1.next(ReactorNettyClient.java:244)
	at io.r2dbc.mssql.client.ReactorNettyClient$1.next(ReactorNettyClient.java:204)
	at io.r2dbc.mssql.message.token.Tabular$TabularDecoder.decode(Tabular.java:424)
	at io.r2dbc.mssql.client.ConnectionState$4$1.decode(ConnectionState.java:206)
	at io.r2dbc.mssql.client.StreamDecoder.withState(StreamDecoder.java:137)
	at io.r2dbc.mssql.client.StreamDecoder.decode(StreamDecoder.java:109)
	at io.r2dbc.mssql.client.ReactorNettyClient.lambda$new$6(ReactorNettyClient.java:254)
	at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:177)
	at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:256)
	at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:362)
	at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:358)
	at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:96)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
	at io.r2dbc.mssql.client.ssl.TdsSslHandler.channelRead(TdsSslHandler.java:380)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.base/java.lang.Thread.run(Thread.java:832)
	Suppressed: java.lang.Exception: #block terminated with an error
		at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:99)
		at reactor.core.publisher.Mono.block(Mono.java:1680)
		at com.example.MsSqlAppKt.main(MsSqlApp.kt:33)

Process finished with exit code 1

@mp911de mp911de self-assigned this Mar 9, 2021
@mp911de
Copy link
Member

mp911de commented Mar 9, 2021

The issue seems to be rooted in R2dbcEntityTemplate.

		DatabaseClient.create(connectionFactory)
				.sql("INSERT INTO customer VALUES(:customerid, :name)")
				.bind("customerid", "1234")
				.bind("name", "12345678901")
				.then().block();

works for me while R2dbcEntityTemplate.insert(new Customer("1234", "12345678901")).block(); does not. Investigation ongoing.

@mp911de mp911de added type: bug A general bug and removed status: waiting-for-triage An issue we've not yet triaged labels Mar 9, 2021
@mp911de
Copy link
Member

mp911de commented Mar 9, 2021

What happens here is quite interesting. First, SQL server sends a warning (error) frame containing the actual error.

2021-03-09 10:38:31,316 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Warning: Code [8152] Severity [GENERAL_ERROR]: String or binary data would be truncated.

Then, the server response contains a row including column description:

2021-03-09 10:38:31,318 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: ColumnMetadataToken [columns=[Column [name='GENERATED_KEYS", type=MutableTypeInformation [maxLength=17, lengthStrategy=BYTELENTYPE, precision=38, displaySize=40, scale=0, flags=33, serverType=numeric, userType=0, udtTypeName="null", collation=null, charset=null], table=null]]]
2021-03-09 10:38:31,318 [reactor-tcp-nio-2] DEBUG MssqlResult - [cid: 0x1] Result column definition: ColumnMetadataToken [columns=[Column [name='GENERATED_KEYS", type=MutableTypeInformation [maxLength=17, lengthStrategy=BYTELENTYPE, precision=38, displaySize=40, scale=0, flags=33, serverType=numeric, userType=0, udtTypeName="null", collation=null, charset=null], table=null]]]
2021-03-09 10:38:31,318 [reactor-tcp-nio-2] DEBUG ReactorNettyClient - [cid: 0x1] Response: io.r2dbc.mssql.message.token.RowToken@14394505

The driver emits the row and then sends an error signal. R2dbcEntityTemplate internally consumed the first element and ignored the error signal.

@mp911de
Copy link
Member

mp911de commented Mar 9, 2021

I think it makes sense to address this issue within the R2DBC driver directly so that a query that has seen an error doesn't emit rows at all.

@mp911de mp911de changed the title Exception not thrown as expected when do saving a record on Microsoft SQL Server (r2dbc-mssql) INSERT doesn't propagate error signals after data signal Mar 9, 2021
@mp911de mp911de changed the title INSERT doesn't propagate error signals after data signal R2dbcEntityTemplate.insert(…) doesn't propagate error signals after data signal Mar 9, 2021
@mp911de mp911de added this to the 1.1.8 (Neumann SR8) milestone Mar 9, 2021
mp911de added a commit that referenced this issue Mar 9, 2021
R2dbcEntityTemplate.insert(…) now fully consumes the response from the INSERT call before continuing. Previously, we consumed only the first signal and continued then. A driver could emit a row and then an error signal and so the error signal would go unnoticed.

Closes #552.
mp911de added a commit that referenced this issue Mar 9, 2021
R2dbcEntityTemplate.insert(…) now fully consumes the response from the INSERT call before continuing. Previously, we consumed only the first signal and continued then. A driver could emit a row and then an error signal and so the error signal would go unnoticed.

Closes #552.
@mp911de mp911de closed this as completed in 0c20272 Mar 9, 2021
@tododo
Copy link

tododo commented Mar 9, 2021

I think it makes sense to address this issue within the R2DBC driver directly so that a query that has seen an error doesn't emit rows at all.

hi @mp911de thanks for reply me in #180

I think it is desired to give the application the choice to whether to determine whether to expect the return value. And the statement returned/prepared by spring-data should be "smart" enough determined to add filter statement or not.

private <T> Mono<T> doInsert(T entity, SqlIdentifier tableName, OutboundRow outboundRow) {

		StatementMapper mapper = dataAccessStrategy.getStatementMapper();
		StatementMapper.InsertSpec insert = mapper.createInsert(tableName);

		for (SqlIdentifier column : outboundRow.keySet()) {
			Parameter settableValue = outboundRow.get(column);
			if (settableValue.hasValue()) {
				insert = insert.withColumn(column, settableValue);
			}
		}

		PreparedOperation<?> operation = mapper.getMappedObject(insert);

		return this.databaseClient.sql(operation) //
				.filter(statement -> statement.returnGeneratedValues()) // **some enhancement here**
				.map(this.dataAccessStrategy.getConverter().populateIdIfNecessary(entity)) //
				.first() //
				.defaultIfEmpty(entity) //
				.flatMap(saved -> maybeCallAfterSave(saved, outboundRow, tableName));
	```

@mp911de
Copy link
Member

mp911de commented Mar 9, 2021

Looking at JDBC, calling INSERT INTO … ; SELECT SCOPE_IDENTITY() fails with the first error and callers aren't able to obtain the result of SELECT SCOPE_IDENTITY(). The SQL Server driver caches the failure and emits it as last signal. Results therefore come already in a different order compared to JDBC.

For now, we await all results to reliably catch the failure.

@tododo
Copy link

tododo commented Mar 9, 2021

Looking at JDBC, calling INSERT INTO … ; SELECT SCOPE_IDENTITY() fails with the first error and callers aren't able to obtain the result of SELECT SCOPE_IDENTITY(). The SQL Server driver caches the failure and emits it as last signal. Results therefore come already in a different order compared to JDBC.

For now, we await all results to reliably catch the failure.

yes, and this is where the transaction rollback cause process hang up there.

the way to bypass for us right now is to use execute on DatabaseClient not the typed insert nor save()/saveAll() on SimpleR2DBCRepository

@tododo
Copy link

tododo commented Mar 11, 2021

@mp911de with this change it can fix the exception not throw, but transaction is till hanging.

'''2021-03-11 21:44:51,892 DEBUG onnectionfactory.R2dbcTransactionManager: 139 - Creating new transaction with name [org.springframework.data.r2dbc.repository.support.AbstractSimpleR2dbcRepositoryIntegrationTests$TransactionalService.shouldRollbackRepository]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT
2021-03-11 21:44:52,367 DEBUG onnectionfactory.R2dbcTransactionManager: 219 - Acquired Connection [MonoFlatMap] for R2DBC transaction
2021-03-11 21:44:52,370 DEBUG onnectionfactory.R2dbcTransactionManager: 464 - Switching R2DBC Connection [io.r2dbc.mssql.MssqlConnection@6d08140f] to manual commit
2021-03-11 21:44:52,469 DEBUG rk.data.r2dbc.core.DefaultDatabaseClient:1414 - Executing SQL statement [INSERT INTO legoset (name, manual) VALUES (@P0_name, @P1_manual)]
2021-03-11 21:44:52,532 DEBUG rk.data.r2dbc.core.DefaultDatabaseClient:1414 - Executing SQL statement [INSERT INTO legoset (name, manual) VALUES (@P0_name, @P1_manual)]
2021-03-11 21:44:52,546 DEBUG support.SqlStateR2dbcExceptionTranslator: 92 - Extracted SQL state class 'S0' from value 'S0001'
2021-03-11 21:44:52,553 DEBUG onnectionfactory.R2dbcTransactionManager: 505 - Initiating transaction rollback
2021-03-11 21:44:52,553 DEBUG onnectionfactory.R2dbcTransactionManager: 338 - Rolling back R2DBC transaction on Connection [io.r2dbc.mssql.MssqlConnection@6d08140f]
2021-03-11 21:44:52,558 ERROR reactor.core.publisher.Operators: 319 - Operator called default onErrorDropped
io.r2dbc.mssql.ExceptionFactory$MssqlNonTransientException: String or binary data would be truncated in table 'master.dbo.legoset', column 'name'. Truncated value: 'ggoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoodgoo'.
at io.r2dbc.mssql.ExceptionFactory.createException(ExceptionFactory.java:145)
Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException:
Error has been observed at the following site(s):
|_ checkpoint ⇢ SQL "INSERT INTO legoset (name, manual) VALUES (@P0_name, @P1_manual)" [DatabaseClient]
Stack trace:
at io.r2dbc.mssql.ExceptionFactory.createException(ExceptionFactory.java:145)
at io.r2dbc.mssql.ExceptionFactory.createException(ExceptionFactory.java:174)
at io.r2dbc.mssql.RpcQueryMessageFlow.lambda$exchange$1(RpcQueryMessageFlow.java:149)
at reactor.core.publisher.FluxHandle$HandleConditionalSubscriber.onNext(FluxHandle.java:303)
at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:426)
at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:268)
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:112)
at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onNext(MonoFlatMapMany.java:242)
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
at reactor.core.publisher.EmitterProcessor.drain(EmitterProcessor.java:426)
at reactor.core.publisher.EmitterProcessor.onNext(EmitterProcessor.java:268)
at io.r2dbc.mssql.client.ReactorNettyClient$1.next(ReactorNettyClient.java:231)
at io.r2dbc.mssql.client.ReactorNettyClient$1.next(ReactorNettyClient.java:191)
at io.r2dbc.mssql.message.token.Tabular$TabularDecoder.decode(Tabular.java:425)
at io.r2dbc.mssql.client.ConnectionState$4$1.decode(ConnectionState.java:206)
at io.r2dbc.mssql.client.StreamDecoder.withState(StreamDecoder.java:137)
at io.r2dbc.mssql.client.StreamDecoder.decode(StreamDecoder.java:109)
at io.r2dbc.mssql.client.ReactorNettyClient.lambda$new$6(ReactorNettyClient.java:241)
at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:177)
at reactor.netty.channel.FluxReceive.drainReceiver(FluxReceive.java:218)
at reactor.netty.channel.FluxReceive.onInboundNext(FluxReceive.java:351)
at reactor.netty.channel.ChannelOperations.onInboundNext(ChannelOperations.java:348)
at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:89)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
at io.r2dbc.mssql.client.ssl.TdsSslHandler.channelRead(TdsSslHandler.java:402)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:352)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1422)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:360)
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:931)
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700)
at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635)
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514)
at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1050)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)

Process finished with exit code 130 (interrupted by signal 2: SIGINT)
'''

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
type: bug A general bug
Projects
None yet
Development

No branches or pull requests

4 participants